**** dT 0.000 * top TEST ../../../../bin/vinyltest/tests/u00006.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:48747 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub **** top extmacro def topsrc=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/../.. **** top macro def testdir=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests **** top macro def tmpdir=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc **** top macro def vtcid=vtc.437008.67e56afc ** top === vtest "vinyllog coverage" * top VTEST vinyllog coverage ** top === server s1 -repeat 2 { ** s1 Starting server **** dT 0.001 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=38786 **** s1 macro def s1_sock=127.0.0.1:38786 * s1 Listen on 127.0.0.1:38786 ** top === vinyl v1 -vcl+backend {} -start ** s1 Started on 127.0.0.1:38786 (2 iterations) **** dT 0.011 ** v1 Launch *** v1 CMD: cd ${pwd} && exec vinyld -d -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37730' -P /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1/vinyld.pid -p vmod_path=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: *** v1 CMD: cd /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37730' -P /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1/vinyld.pid -p vmod_path=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: *** v1 PID: 437018 **** v1 macro def v1_pid=437018 **** v1 macro def v1_name=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 **** dT 0.045 *** v1 debug|Warning: mlock() of VSM failed: Not owner (1 *** v1 debug|) **** dT 0.048 *** v1 debug|Debug: Version: vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug|Debug: Platform: -jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|200 292 *** v1 debug|----------------------------- *** v1 debug|Vinyl Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.147 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 *** v1 CLI RX 107 **** v1 CLI RX|fpdpqfdgxmbncrntdnmoutdsiifgkvqb **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth fb04d2efa328d4329b6c6eb16e047117ca01079a113529652ecf57c238ba99bf **** dT 0.148 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Vinyl Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "38786"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.248 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.348 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.448 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.548 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.648 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.748 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.849 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.888 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|Message from C-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.898 *** v1 debug|Debug: *** v1 debug| Child (437196) Started **** dT 0.930 *** v1 debug|Child launched OK **** dT 0.932 *** v1 CLI RX 200 *** v1 debug|Info: Child (437196) said Child starts *** v1 wait-running **** v1 CLI TX|status *** v1 debug| *** v1 debug|Info: Child (437196) said Security: proc_setid missing, uid/gid unchanged *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 51476 **** v1 CLI TX|debug.xid 1000 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 51476 ** v1 Listen on 127.0.0.1 51476 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=51476 **** v1 macro def v1_sock=127.0.0.1:51476 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=51476 **** v1 macro def v1_a0_sock=127.0.0.1:51476 **** dT 0.949 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773717746.373372/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1773717746.373372/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:51476 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:51476 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 51476 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 51476 **** dT 1.032 ** top === process p1 { **** dT 1.044 **** p1 CMD: exec vinyllog -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -g raw -u -A -w - **** dT 1.045 *** p1 PID: 437213 **** dT 1.047 **** p1 macro def p1_pid=437213 **** p1 macro def p1_dir=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/p1 **** p1 macro def p1_out=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/p1/term **** p1 macro def p1_err=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/p1/stderr ** top === shell { **** top shell_cmd|set -e ;exec 2>&1 ; **** top shell_cmd|\texec vinyllog -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -D -P /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/vlog.pid \ **** top shell_cmd|\t -w /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/vlog.bin -R 10/s \ **** top shell_cmd|\t -i RespStatus -i ReqURL -i BereqURL **** dT 1.104 **** top shell_status = 0x0000 ** top === shell -match "Usage: .*vinyllog " \ **** dT 1.105 **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -h **** dT 1.156 **** top shell_out|Usage: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyllog/.libs/vinyllog **** top shell_out| **** top shell_out|Options: **** top shell_out| [-a] Append to file **** top shell_out| [-A] Text output **** top shell_out| [-b] Only display backend records **** top shell_out| [-c] Only display client records **** top shell_out| [-C] Caseless regular expressions **** top shell_out| [-d] Process old log entries and exit **** top shell_out| [-D] Daemonize **** top shell_out| [-E] Display ESI transactions **** top shell_out| [-g ] Grouping mode (default: vxid) **** top shell_out| [-h] Usage help **** top shell_out| [-i ] Include tags **** top shell_out| [-I <[taglist:]regex>] Include by regex **** top shell_out| [-k ] Limit transactions **** top shell_out| [-L ] Incomplete transaction limit **** top shell_out| [-n ] vinyl working directory **** top shell_out| [-P ] PID file **** top shell_out| [-Q ] VSL query file **** top shell_out| [-q ] VSL query **** top shell_out| [-r ] Binary file input **** top shell_out| [-R ] Output rate limit **** top shell_out| [-t ] VSM connection timeout **** top shell_out| [-T ] Transaction end timeout **** top shell_out| [-u] Unbuffered output **** top shell_out| [-v] Verbose record printing **** top shell_out| [-V] Version **** top shell_out| [-w ] Output filename **** top shell_out| [-x ] Exclude tags **** top shell_out| [-X <[taglist:]regex>] Exclude by regex **** top shell_status = 0x0000 **** top shell_match succeeded ** top === shell -expect "Copyright (c) 2006 Verdens Gang AS" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -V **** dT 1.208 **** top shell_out|/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyllog/.libs/vinyllog (vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4) **** top shell_out|Copyright (c) 2006 Verdens Gang AS **** top shell_out|Copyright (c) 2006-2026 Varnish Software **** top shell_out|Copyright 2010-2026 UPLEX - Nils Goroll Systemoptimierung **** top shell_out|Copyright 2026 The Vinyl Cache Project **** top shell_status = 0x0000 **** top shell_expect found ** top === shell -err -match "Usage: .*vinyllog " \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog extra **** dT 1.260 **** top shell_out|Usage: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyllog/.libs/vinyllog **** top shell_out| **** top shell_out|Options: **** top shell_out| [-a] Append to file **** top shell_out| [-A] Text output **** top shell_out| [-b] Only display backend records **** top shell_out| [-c] Only display client records **** top shell_out| [-C] Caseless regular expressions **** top shell_out| [-d] Process old log entries and exit **** top shell_out| [-D] Daemonize **** top shell_out| [-E] Display ESI transactions **** top shell_out| [-g ] Grouping mode (default: vxid) **** top shell_out| [-h] Usage help **** top shell_out| [-i ] Include tags **** top shell_out| [-I <[taglist:]regex>] Include by regex **** top shell_out| [-k ] Limit transactions **** top shell_out| [-L ] Incomplete transaction limit **** top shell_out| [-n ] vinyl working directory **** top shell_out| [-P ] PID file **** top shell_out| [-Q ] VSL query file **** top shell_out| [-q ] VSL query **** top shell_out| [-r ] Binary file input **** top shell_out| [-R ] Output rate limit **** top shell_out| [-t ] VSM connection timeout **** top shell_out| [-T ] Transaction end timeout **** top shell_out| [-u] Unbuffered output **** top shell_out| [-v] Verbose record printing **** top shell_out| [-V] Version **** top shell_out| [-w ] Output filename **** top shell_out| [-x ] Exclude tags **** top shell_out| [-X <[taglist:]regex>] Exclude by regex **** top shell_status = 0x0001 **** top shell_match succeeded ** top === shell -err -expect "Missing -w option" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -D **** dT 1.309 **** top shell_out|Missing -w option **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Daemon cannot write to stdout" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -D -w - **** dT 1.359 **** top shell_out|Daemon cannot write to stdout **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Ambiguous grouping type: r" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -g r **** dT 1.410 **** top shell_out|Ambiguous grouping type: r **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Unknown grouping type: foo" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -g foo **** dT 1.460 **** top shell_out|Unknown grouping type: foo **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-k: Invalid number 'foo'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -k foo **** dT 1.512 **** top shell_out|-k: Invalid number 'foo' **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-L: Range error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -L 0 **** dT 1.565 **** top shell_out|-L: Range error **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-i: "foo" matches zero tags} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -i foo **** dT 1.615 **** top shell_out|-i: "foo" matches zero tags **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-i: "Resp" is ambiguous} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -i Resp **** dT 1.663 **** top shell_out|-i: "Resp" is ambiguous **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-i: Syntax error in "Re**sp"} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -i Re**sp **** dT 1.715 **** top shell_out|-i: Syntax error in "Re**sp" **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-I: "foo" matches zero tags} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -I foo:bar **** dT 1.766 **** top shell_out|-I: "foo" matches zero tags **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-I: "Resp" is ambiguous} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -I Resp:bar **** dT 1.825 **** top shell_out|-I: "Resp" is ambiguous **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-I: Regex error at position 4 (missing c... **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -I "(foo" **** dT 1.879 **** top shell_out|-I: Regex error at position 4 (missing closing parenthesis) **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-t: Invalid argument" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -t -1 **** dT 1.932 **** top shell_out|-t: Invalid argument: -1 **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-t: Invalid argument" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -t foo **** dT 1.986 **** top shell_out|-t: Invalid argument: foo **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-t: Invalid argument" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -t NaN **** dT 2.040 **** top shell_out|-t: Invalid argument: NaN **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-x: Syntax error in "**"} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -x "**" **** dT 2.096 **** top shell_out|-x: Syntax error in "**" **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect {-X: Syntax error in "**"} \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -X "**:bar" **** dT 2.155 **** top shell_out|-X: Syntax error in "**" **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Cannot open output file (No such file or... **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -w /nonexistent/file **** dT 2.210 **** top shell_out|Cannot open output file (No such file or directory) **** top shell_status = 0x0002 **** top shell_expect found ** top === shell -err -expect "Only one of -n and -r options may be use... **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -r /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1/_.vsm **** dT 2.266 **** top shell_out|Only one of -n and -r options may be used **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Unterminated string" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q '"b\\la' **** dT 2.321 **** top shell_out|Query expression error: **** top shell_out|Unterminated string (Pos 7) **** top shell_out|"b\\la **** top shell_out|###### **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Syntax error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q ' / ' **** dT 2.377 **** top shell_out|Query expression error: **** top shell_out|Syntax error (Pos 2) **** top shell_out| / **** top shell_out|-#- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected integer got '}" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q {} **** dT 2.431 **** top shell_out|Query expression error: **** top shell_out|Expected integer got '}' (Pos 2) **** top shell_out|{} **** top shell_out|-# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected positive integer" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q {-1} **** dT 2.488 **** top shell_out|Query expression error: **** top shell_out|Expected positive integer (Pos 2) **** top shell_out|{-1} **** top shell_out|-##- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Syntax error in level limit" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q {1a} **** dT 2.546 **** top shell_out|Query expression error: **** top shell_out|Syntax error in level limit (Pos 2) **** top shell_out|{1a} **** top shell_out|-##- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected VSL tag name got '['" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "[]" **** dT 2.604 **** top shell_out|Query expression error: **** top shell_out|Expected VSL tag name got '[' (Pos 1) **** top shell_out|[] **** top shell_out|#- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Tag name matches zero tags" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q foo **** dT 2.659 **** top shell_out|Query expression error: **** top shell_out|Tag name matches zero tags (Pos 1) **** top shell_out|foo **** top shell_out|### **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Tag name is ambiguous" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q Resp **** dT 2.714 **** top shell_out|Query expression error: **** top shell_out|Tag name is ambiguous (Pos 1) **** top shell_out|Resp **** top shell_out|#### **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected string got '['" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "ReqHeader:[]" **** dT 2.770 **** top shell_out|Query expression error: **** top shell_out|Expected string got '[' (Pos 11) **** top shell_out|ReqHeader:[] **** top shell_out|----------#- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected integer got ']'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "ReqHeader:foo[]" **** dT 2.829 **** top shell_out|Query expression error: **** top shell_out|Expected integer got ']' (Pos 15) **** top shell_out|ReqHeader:foo[] **** top shell_out|--------------# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected positive integer" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "ReqHeader:foo[a]" **** dT 2.888 **** top shell_out|Query expression error: **** top shell_out|Expected positive integer (Pos 15) **** top shell_out|ReqHeader:foo[a] **** top shell_out|--------------#- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Syntax error in tag name" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q '*x* eq "foo"' **** dT 2.944 **** top shell_out|Query expression error: **** top shell_out|Syntax error in tag name (Pos 1) **** top shell_out|*x* eq "foo" **** top shell_out|###--------- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected number got '>'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "RespStatus > >" **** dT 3.008 **** top shell_out|Query expression error: **** top shell_out|Expected number got '>' (Pos 14) **** top shell_out|RespStatus > > **** top shell_out|-------------# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Floating point parse error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "Timestamp:Start[1] > 0.foo" **** dT 3.066 **** top shell_out|Query expression error: **** top shell_out|Floating point parse error (Pos 22) **** top shell_out|Timestamp:Start[1] > 0.foo **** top shell_out|---------------------##### **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Integer parse error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "RespStatus > foo" **** dT 3.123 **** top shell_out|Query expression error: **** top shell_out|Integer parse error (Pos 14) **** top shell_out|RespStatus > foo **** top shell_out|-------------### **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected string got '>'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "ReqMethod eq >" **** dT 3.174 **** top shell_out|Query expression error: **** top shell_out|Expected string got '>' (Pos 14) **** top shell_out|ReqMethod eq > **** top shell_out|-------------# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected regular expression got '>'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "ReqMethod ~ >" **** dT 3.227 **** top shell_out|Query expression error: **** top shell_out|Expected regular expression got '>' (Pos 13) **** top shell_out|ReqMethod ~ > **** top shell_out|------------# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Regular expression error: " \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q 'ReqMethod ~ "("' **** dT 3.279 **** top shell_out|Query expression error: **** top shell_out|Regular expression error: missing closing parenthesis (Pos 14) **** top shell_out|ReqMethod ~ "(" **** top shell_out|------------#^# **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "Expected operator got 'ReqMethod'" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -q "RespStatus ReqMethod 200" **** dT 3.330 **** top shell_out|Query expression error: **** top shell_out|Expected operator got 'ReqMethod' (Pos 12) **** top shell_out|RespStatus ReqMethod 200 **** top shell_out|-----------#########---- **** top shell_out| **** top shell_out| **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 1foo **** dT 3.382 **** top shell_out|-R: Syntax error **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Range error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 0 **** dT 3.433 **** top shell_out|-R: Range error **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Range error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R -1 **** dT 3.489 **** top shell_out|-R: Range error **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Range error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 3000000000 **** dT 3.543 **** top shell_out|-R: Range error **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error: Invalid duration" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 10/0s **** dT 3.591 **** top shell_out|-R: Syntax error: Invalid duration **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error: Invalid duration" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 10/-10s **** dT 3.641 **** top shell_out|-R: Syntax error: Invalid duration **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error: Invalid duration" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 10/1q **** dT 3.692 **** top shell_out|-R: Syntax error: Invalid duration **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error: Invalid duration" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 10/11f09s **** dT 3.742 **** top shell_out|-R: Syntax error: Invalid duration **** top shell_status = 0x0001 **** top shell_expect found ** top === shell -err -expect "-R: Syntax error" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -R 1000000000/1000000000000000000000000000000s **** dT 3.793 **** top shell_out|-R: Syntax error **** top shell_status = 0x0001 **** top shell_expect found ** top === process p1 -expect-text 0 0 "0 CLI" **** dT 3.943 **** p1 found expected text at 1,18: '0 CLI' ** top === process p1 -screen_dump *** p1 screen| 0 CLI - Rd ping *** p1 screen| 0 CLI - Wr 200 19 PONG 1773717750 1.0 *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 screen| *** p1 Cursor at line 3 column 1 ** top === process p1 -stop **** p1 Sent signal 15 **** p1 stderr read 0 **** p1 stdout read 0 **** dT 3.944 ** p1 WAIT4 pid=437213 status=0x0000 (user 0.022000 sys 0.047000) **** p1 macro undef p1_pid **** dT 3.951 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717750 1.0 **** dT 4.944 ** top === shell -match "0 CLI[ ]+- Wr 200 [0-9]+ PONG" \ **** top shell_cmd|set -e ;exec 2>&1 ; vinyllog -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1 -d -g raw -X "Wr 200 [0-9]+ [^P]" **** dT 5.096 **** top shell_out| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773717746.373372/vgc.so 1auto **** top shell_out| 0 CLI - Rd vcl.use "vcl1" **** top shell_out| 0 CLI - Rd start **** top shell_out| 0 Debug - "sockopt: Setting SO_LINGER for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_NODELAY for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:51476%00" **** top shell_out| 0 CLI - Rd debug.listen_address **** top shell_out| 0 CLI - Rd debug.xid 1000 **** top shell_out| 0 CLI - Rd debug.listen_address **** top shell_out| 0 CLI - Rd ping **** top shell_out| 0 CLI - Wr 200 19 PONG 1773717750 1.0 **** top shell_status = 0x0000 **** top shell_match succeeded ** top === shell -match "0 CLI[ ]+- Wr 200 [0-9]+ PONG" \ **** top shell_cmd|set -e ;exec 2>&1 ; VINYL_DEFAULT_N="/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/v1" vinyllog -d -g raw -X "Wr 200 [0-9]+ [^P]" **** dT 5.248 **** top shell_out| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773717746.373372/vgc.so 1auto **** top shell_out| 0 CLI - Rd vcl.use "vcl1" **** top shell_out| 0 CLI - Rd start **** top shell_out| 0 Debug - "sockopt: Setting SO_LINGER for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_NODELAY for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:51476%00" **** top shell_out| 0 Debug - "sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:51476%00" **** top shell_out| 0 CLI - Rd debug.listen_address **** top shell_out| 0 CLI - Rd debug.xid 1000 **** top shell_out| 0 CLI - Rd debug.listen_address **** top shell_out| 0 CLI - Rd ping **** top shell_out| 0 CLI - Wr 200 19 PONG 1773717750 1.0 **** top shell_status = 0x0000 **** top shell_match succeeded ** top === client c1 { ** c1 Starting client ** c1 Waiting for client ** c1 Started on 127.0.0.1:51476 (1 iterations) *** c1 Connect to 127.0.0.1:51476 *** c1 connected fd 18 from 127.0.0.1 45147 to 127.0.0.1:51476 ** c1 === txreq -url /foo **** c1 txreq|GET /foo HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** dT 5.249 *** s1 accepted fd 4 127.0.0.1 49041 ** s1 === rxreq **** dT 5.250 **** s1 rxhdr|GET /foo HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Vinyl: 1002\r **** s1 rxhdr|\r **** s1 rxhdrlen = 153 **** s1 http[ 0] |GET **** s1 http[ 1] |/foo **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Vinyl-Cache/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Vinyl: 1002 **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 17 Mar 2026 03:22:31 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r *** s1 shutting fd 4 (server run) **** dT 5.252 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 45147 a0 127.0.0.1 51476 1773717751.473593 16 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:51476 **** v1 vsl| 1000 Link c req 1001 rxreq **** dT 5.261 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Tue, 17 Mar 2026 03:22:31 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Vinyl: 1001\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 189 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Date: Tue, 17 Mar 2026 03:22:31 GMT **** c1 http[ 4] |Server: s1 **** c1 http[ 5] |Content-Length: 0 **** c1 http[ 6] |X-Vinyl: 1001 **** c1 http[ 7] |Age: 0 **** c1 http[ 8] |Via: 1.1 v1 (Vinyl-Cache/trunk) **** c1 http[ 9] |Accept-Ranges: bytes **** c1 http[10] |Connection: keep-alive **** c1 bodylen = 0 *** c1 closing fd 18 ** c1 Ending ** top === delay 1 *** top delaying 1 second(s) **** dT 5.352 **** v1 vsl| 1002 Begin b bereq 1001 fetch **** v1 vsl| 1002 VCL_use b vcl1 **** v1 vsl| 1002 Timestamp b Start: 1773717751.474038 0.000000 0.000000 **** v1 vsl| 1002 BereqMethod b GET **** v1 vsl| 1002 BereqURL b /foo **** v1 vsl| 1002 BereqProtocol b HTTP/1.1 **** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b User-Agent: c1 **** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1002 BereqHeader b X-Vinyl: 1002 **** v1 vsl| 1002 VCL_call b BACKEND_FETCH **** v1 vsl| 1002 VCL_return b fetch **** v1 vsl| 1002 Timestamp b Fetch: 1773717751.474101 0.000062 0.000062 **** v1 vsl| 1002 Timestamp b Connected: 1773717751.474233 0.000195 0.000132 **** v1 vsl| 1002 BackendOpen b 19 s1 127.0.0.1 38786 127.0.0.1 49041 connect **** v1 vsl| 1002 Timestamp b Bereq: 1773717751.474303 0.000264 0.000069 **** v1 vsl| 1002 BerespProtocol b HTTP/1.1 **** v1 vsl| 1002 BerespStatus b 200 **** v1 vsl| 1002 BerespReason b OK **** v1 vsl| 1002 BerespHeader b Date: Tue, 17 Mar 2026 03:22:31 GMT **** v1 vsl| 1002 BerespHeader b Server: s1 **** v1 vsl| 1002 BerespHeader b Content-Length: 0 **** v1 vsl| 1002 Timestamp b Beresp: 1773717751.475012 0.000973 0.000708 **** v1 vsl| 1002 TTL b RFC 120 10 0 1773717751 1773717751 1773717751 0 0 cacheable **** v1 vsl| 1002 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1002 VCL_return b deliver **** v1 vsl| 1002 Debug b Missing content-range header or unknown range unit **** v1 vsl| 1002 Timestamp b Process: 1773717751.475091 0.001052 0.000078 **** v1 vsl| 1002 Filters b **** v1 vsl| 1002 Storage b umem s0 **** v1 vsl| 1002 Fetch_Body b 0 none - **** v1 vsl| 1002 BackendClose b 19 s1 recycle **** v1 vsl| 1002 Timestamp b BerespBody: 1773717751.485434 0.011395 0.010343 **** v1 vsl| 1002 Length b 0 **** v1 vsl| 1002 BereqAcct b 153 0 153 87 0 87 **** v1 vsl| 1002 End b **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1773717751.473798 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1773717751.473798 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 45147 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c /foo **** v1 vsl| 1001 ReqProtocol c HTTP/1.1 **** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c User-Agent: c1 **** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1001 VCL_call c RECV **** v1 vsl| 1001 VCL_return c hash **** v1 vsl| 1001 VCL_call c HASH **** v1 vsl| 1001 VCL_return c lookup **** v1 vsl| 1001 VCL_call c MISS **** v1 vsl| 1001 VCL_return c fetch **** v1 vsl| 1001 Link c bereq 1002 fetch **** v1 vsl| 1001 Timestamp c Fetch: 1773717751.485443 0.011645 0.011645 **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 200 **** v1 vsl| 1001 RespReason c OK **** v1 vsl| 1001 RespHeader c Date: Tue, 17 Mar 2026 03:22:31 GMT **** v1 vsl| 1001 RespHeader c Server: s1 **** v1 vsl| 1001 RespHeader c Content-Length: 0 **** v1 vsl| 1001 RespHeader c X-Vinyl: 1001 **** v1 vsl| 1001 RespHeader c Age: 0 **** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1001 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1001 VCL_call c DELIVER **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1773717751.485487 0.011688 0.000043 **** v1 vsl| 1001 Filters c **** v1 vsl| 1001 RespHeader c Connection: keep-alive **** v1 vsl| 1001 Timestamp c Resp: 1773717751.485511 0.011712 0.000024 **** v1 vsl| 1001 ReqAcct c 54 0 54 189 0 189 **** v1 vsl| 1001 End c **** v1 vsl| 1000 SessClose c REM_CLOSE 0.013 **** v1 vsl| 1000 End c **** dT 6.262 ** top === shell "mv ${tmpdir}/vlog.bin ${tmpdir}/vlog.bin~" **** top shell_cmd|set -e ;exec 2>&1 ; mv /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/vlog.bin /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.437008.67e56afc/vlog.bin~ ---- top popen fails: Resource temporarily unavailable * top RESETTING after ../../../../bin/vinyltest/tests/u00006.vtc ** s1 Waiting for server (3/-1) ** v1 Wait **** v1 CLI TX|panic.show *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared **** dT 6.952 **** v1 vsl| 0 CLI - Rd ping **** dT 6.953 **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717753 1.0 **** dT 9.954 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717756 1.0 **** dT 12.956 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717759 1.0 **** dT 15.957 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717762 1.0 **** dT 18.959 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717765 1.0 **** dT 21.961 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717768 1.0 **** dT 24.962 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717771 1.0 **** dT 27.964 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717774 1.0 **** dT 30.966 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717777 1.0 **** dT 33.968 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717780 1.0 **** dT 36.970 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717783 1.0 **** dT 39.971 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717786 1.0 **** dT 42.973 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717789 1.0 **** dT 45.975 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717792 1.0 **** dT 48.976 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717795 1.0 **** dT 51.978 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717798 1.0 **** dT 54.979 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717801 1.0 **** dT 57.981 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1773717804 1.0 # top TEST ../../../../bin/vinyltest/tests/u00006.vtc TIMED OUT (kill -9) # top TEST ../../../../bin/vinyltest/tests/u00006.vtc FAILED (60.002) signal=9 FAIL tests/u00006.vtc (exit status: 2)